Implement Structured Console Logging - #83

src/TeaPie/Logging/TreeScope.cs (1)

23-28: Closing bracket always rendered at Information level regardless of scope content.

Line 27 hardcodes LogEventLevel.Information for the closing tree line. If the scope contained only Debug or Warning messages, the closing └── header will show INF, creating a visual mismatch with the opening line (which uses the actual event level from TreeConsoleSink). Consider capturing the level used for the opening line in ScopeState and reusing it here.

src/TeaPie/Http/ExecuteRequestStep.cs (2)

57-61: Tree scope around a single log statement adds visual noise without grouping benefit.

BeginTreeScope here wraps exactly one LogDebug call. This produces an opening bracket ┌──, the message, and a closing bracket └── for a single line — adding clutter rather than structure. Consider either removing the scope or including additional related log statements within it.

---

114-128: Duplicated request-sending logic between retry and non-retry paths.

Both branches perform identical GetMessage → Options.Set → SendAsync sequences. The only difference is the tree scope wrapper. You could extract the common logic and conditionally wrap it.

♻️ Suggested refactor

-            if (retryAttemptNumber > 0)
-            {
-                using (logger.BeginTreeScope())
-                {
-                    var retryRequest = GetMessage(requestExecutionContext, originalMessage, content, ref messageUsed);
-                    retryRequest.Options.Set(_contextKey, requestExecutionContext);
-                    return await client.SendAsync(retryRequest, token);
-                }
-            }
-            else
-            {
-                var request = GetMessage(requestExecutionContext, originalMessage, content, ref messageUsed);
-                request.Options.Set(_contextKey, requestExecutionContext);
-                return await client.SendAsync(request, token);
-            }
+            using (retryAttemptNumber > 0 ? logger.BeginTreeScope() : EmptyDisposable.Instance)
+            {
+                var msg = GetMessage(requestExecutionContext, originalMessage, content, ref messageUsed);
+                msg.Options.Set(_contextKey, requestExecutionContext);
+                return await client.SendAsync(msg, token);
+            }

Note: this requires access to EmptyDisposable or relying on the fact that BeginTreeScope already returns one when tree logging is disabled. An alternative is to always call BeginTreeScope for retries and let the extension method handle the no-op case.

src/TeaPie/Logging/TreeConsoleWriter.cs (1)

11-23: Console writes from TreeConsoleWriter are not synchronized with TreeConsoleSink output.

Both TreeConsoleSink.Emit and these WriteOpening/WriteClosing methods write to Console.Out independently. Under concurrent async execution, opening/closing brackets could interleave with log message bodies from the sink. If this becomes an issue, consider routing all tree output through a shared lock or a single writer abstraction.

src/TeaPie/Logging/TreeLoggingExtensions.cs (2)

5-11: Static mutable flag without memory barrier — fine for set-once-at-startup, but worth a note.

_treeLoggingEnabled is written once during startup and read on potentially different threads. The current service-configuration-before-use pattern provides an implicit barrier in most DI frameworks, so this works in practice. If the flag ever needs to be toggled at runtime, consider making it volatile or using Interlocked.

---

13-21: logger parameter is intentionally unused — consider documenting why.

Line 15 discards the parameter (_ = logger). This is a deliberate design choice for API discoverability as an extension method, but it may confuse future maintainers. A brief comment explaining the intent would help.

src/TeaPie/Logging/TreeConsoleSink.cs (2)

51-62: MessageTemplateParser is allocated on every Emit call.

MessageTemplateParser is stateless and safe to reuse. Promote it to a private static readonly field to avoid per-message allocation on a hot path.

Proposed fix

 public class TreeConsoleSink(ITextFormatter formatter) : ILogEventSink
 {
     private const string VerticalBar = "│  ";
+    private static readonly Serilog.Parsing.MessageTemplateParser _parser = new();
 
     private readonly ITextFormatter _formatter = formatter;

     private static LogEvent AddPrefixToMessage(LogEvent original, string prefix)
     {
-        var newMessageTemplate = new Serilog.Parsing.MessageTemplateParser()
-            .Parse(prefix + original.MessageTemplate.Text);
+        var newMessageTemplate = _parser.Parse(prefix + original.MessageTemplate.Text);

---

32-38: printedCount filter is redundant after the loop above.

The loop on lines 22–28 marks every scope as printed, so stack?.Count(s => s.Printed) will always equal stack.Count at this point. You can simplify:

-        var printedCount = stack?.Count(s => s.Printed) ?? 0;
+        var printedCount = stack?.Count ?? 0;

src/TeaPie/Logging/TreeLoggingExtensions.cs (1)

13-21: _ = logger discards the extension method receiver without explanation.

The ILogger parameter exists solely so callers can write logger.BeginTreeScope() naturally, but the implementation never touches it. A brief doc-comment or a #pragma warning disable IDE0060 makes the intent explicit and avoids future readers wondering if a logger reference was accidentally forgotten.

♻️ Suggested clarification

+    /// <summary>
+    /// Begins a tree-structured logging scope. The <paramref name="logger"/> parameter
+    /// is unused; it exists only to enable fluent call-site syntax.
+    /// </summary>
     public static IDisposable BeginTreeScope(this ILogger logger)
     {
-        _ = logger;
+#pragma warning disable IDE0060 // unused parameter is intentional (extension method receiver)
+        _ = logger;
+#pragma warning restore IDE0060

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeLoggingExtensions.cs` around lines 13 - 21, The
extension method BeginTreeScope(ILogger logger) intentionally doesn't use the
logger parameter but currently discards it with "_ = logger" which is confusing;
update the method to make this explicit by either adding a short XML doc comment
on BeginTreeScope explaining the unused receiver is for natural extension-method
call syntax, or suppress the unused-parameter warning with "#pragma warning
disable IDE0060" (and re-enable after) so readers know the omission is
intentional; keep the existing logic referencing _treeLoggingEnabled, returning
EmptyDisposable.Instance or new TreeScope() unchanged.

src/TeaPie/Logging/TreeScope.cs (1)

27-27: Closing bracket always shows INF regardless of actual scope content.

LogEventLevel.Information is hardcoded for both the opening (WriteOpening in TreeConsoleSink) and the closing marker here. If all events in the scope were DBG, the closing └── will still read [HH:mm:ss INF], which is visually inconsistent. Consider storing the highest level seen within the scope in ScopeState and using it here.

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeScope.cs` at line 27, The closing marker currently
hardcodes LogEventLevel.Information; add a highest-seen level to the scope state
(e.g., a property/field on ScopeState such as HighestLevel or MaxLevel) and
ensure all event-recording paths update ScopeState.HighestLevel when an event
with a higher severity is observed; then change the call in TreeScope (where
TreeConsoleWriter.WriteClosing is invoked) to pass
TreeConsoleWriter.LevelToShort(scopeState.HighestLevel) instead of
LogEventLevel.Information so the closing bracket reflects the highest level seen
in the scope.

src/TeaPie/Logging/TreeConsoleSink.cs (2)

32-32: Count(s => s.Printed) is always stack.Count after the preceding loop.

The foreach above guarantees every scope in the stack is marked printed before reaching line 32. The LINQ predicate is therefore always true for every element, making the O(n) enumeration redundant.

♻️ Proposed simplification

-        var printedCount = stack?.Count(s => s.Printed) ?? 0;
+        var printedCount = stack?.Count ?? 0;

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeConsoleSink.cs` at line 32, The computed printedCount
in TreeConsoleSink.cs uses stack?.Count(s => s.Printed) but the preceding
foreach already sets every scope's Printed flag, so the predicate is redundant
and does an extra O(n) enumeration; update the printedCount assignment in the
method containing the loop (referencing the printedCount local and the stack
variable) to use stack?.Count ?? 0 (or simply stack.Count when non-nullable)
instead of Count(s => s.Printed) to avoid the unnecessary pass.

---

13-13: VerticalBar constant is duplicated from TreeConsoleWriter.

"│ " is already defined in TreeConsoleWriter (referenced in TreeConsoleWriter.cs). Keeping a private copy here risks the two diverging silently if the indentation string is ever changed. Expose it from TreeConsoleWriter (e.g., internal const string VerticalBar) and reference it here.

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeConsoleSink.cs` at line 13, The VerticalBar constant
is duplicated; remove the private const string VerticalBar from TreeConsoleSink
and instead reference the single definition on TreeConsoleWriter by making
TreeConsoleWriter.VerticalBar an accessible constant (change its declaration to
internal const string VerticalBar) and update usages in TreeConsoleSink to use
TreeConsoleWriter.VerticalBar so both classes share the same value.

src/TeaPie/Logging/TreeScope.cs (1)

16-31: ⚠️ Potential issue | 🟡 Minor

_disposed = true is still set after WriteClosing — unresolved from previous review.

The guard at line 18 is bypassed on a second Dispose() call if WriteClosing (line 27) throws: _disposed stays false, so the next call re-enters, calls Pop() on an already-modified stack, and may corrupt scope depth for all subsequent/concurrent scopes in the same async context.

🛡️ Proposed fix (set flag or use try/finally)

-        TreeScopeStateStore.Pop();
-
-        if (_state.Printed)
-        {
-            TreeConsoleWriter.WriteClosing(_state.Depth, DateTimeOffset.Now, TreeConsoleWriter.LevelToShort(LogEventLevel.Information));
-        }
-
-        _disposed = true;
+        _disposed = true;
+        TreeScopeStateStore.Pop();
+
+        if (_state.Printed)
+        {
+            TreeConsoleWriter.WriteClosing(_state.Depth, DateTimeOffset.Now, TreeConsoleWriter.LevelToShort(LogEventLevel.Information));
+        }

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeScope.cs` around lines 16 - 31, Dispose can re-enter
if TreeConsoleWriter.WriteClosing throws because _disposed is only set after
that call; to fix, set the _disposed flag immediately after the early-return
guard (i.e., in Dispose() set _disposed = true right after checking if
(_disposed) return) before calling TreeScopeStateStore.Pop() and the
WriteClosing logic (or alternatively wrap Pop()/WriteClosing in try/finally and
set _disposed in the finally) so that subsequent Dispose() calls won't re-enter
and corrupt the TreeScopeStateStore stack; reference Dispose(), _disposed,
TreeScopeStateStore.Pop(), TreeConsoleWriter.WriteClosing, _state.Printed and
_state.Depth when making the change.

Configuration used: defaults

Review profile: CHILL

Plan: Pro

src/TeaPie/Logging/TreeConsoleSink.cs (2)

74-74: public on a member of an internal class — use internal to align with project policy.

The enclosing TreeConsoleSinkExtensions is already internal, so public has no effect on the assembly API surface but is inconsistent with the project-wide guideline of not using public unless necessary.

♻️ Proposed change

-    public static LoggerConfiguration TreeConsole(
+    internal static LoggerConfiguration TreeConsole(
         this LoggerSinkConfiguration sinkConfiguration,

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeConsoleSink.cs` at line 74, The TreeConsole method is
declared public inside the internal TreeConsoleSinkExtensions class; change its
accessibility to internal to match the enclosing class and project policy.
Locate the TreeConsole method in the TreeConsoleSinkExtensions class and replace
the public modifier with internal so the extension method's visibility aligns
with the internal class.

---

58-69: ⚠️ Potential issue | 🟠 Major

MessageTemplateParser per-call allocation and TraceId/SpanId loss still unaddressed.

Two previously flagged issues remain:

1. Parser allocation: new Serilog.Parsing.MessageTemplateParser() is instantiated on every log event that falls inside a tree scope. It is stateless and should be a private static readonly field.

2. Trace context loss: The 5-parameter LogEvent constructor silently drops TraceId and SpanId. Serilog exposes a 7-parameter public constructor (timestamp, level, exception, messageTemplate, properties, traceId, spanId) that preserves trace correlation.

♻️ Proposed fix

+    private static readonly Serilog.Parsing.MessageTemplateParser _templateParser = new();

     private static LogEvent AddPrefixToMessage(LogEvent original, string prefix)
     {
-        var newMessageTemplate = new Serilog.Parsing.MessageTemplateParser()
-            .Parse(prefix + original.MessageTemplate.Text);
+        var newMessageTemplate = _templateParser
+            .Parse(prefix + original.MessageTemplate.Text);

         return new LogEvent(
             original.Timestamp,
             original.Level,
             original.Exception,
             newMessageTemplate,
-            original.Properties.Select(kvp => new LogEventProperty(kvp.Key, kvp.Value)));
+            original.Properties.Select(kvp => new LogEventProperty(kvp.Key, kvp.Value)),
+            original.TraceId ?? default,
+            original.SpanId ?? default);
     }

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeConsoleSink.cs` around lines 58 - 69, Make
MessageTemplateParser a single static instance and use the 7-argument LogEvent
constructor to preserve trace correlation: change AddPrefixToMessage to reuse a
private static readonly Serilog.Parsing.MessageTemplateParser (instead of newing
per call) and call the public LogEvent constructor that accepts (timestamp,
level, exception, messageTemplate, properties, traceId, spanId), passing
original.TraceId and original.SpanId; also materialize the properties sequence
into the expected collection type (e.g., a List<LogEventProperty>) when
constructing the new LogEvent so no properties are lost.

src/TeaPie/Logging/TreeConsoleSink.cs (1)

39-43: Count(s => s.Printed) is always equal to scopes.Count at call-site.

PrintUnopenedScopes marks every scope as printed before BuildIndentPrefix is called, so the predicate is always true and the filtered Count equals scopes.Count. Using scopes?.Count ?? 0 is simpler and avoids an extra LINQ enumeration.

♻️ Proposed simplification

 private static string BuildIndentPrefix(IReadOnlyList<TreeScopeStateStore.ScopeState>? scopes)
 {
-    var printedCount = scopes?.Count(s => s.Printed) ?? 0;
+    var printedCount = scopes?.Count ?? 0;
     return TreeConsoleWriter.BuildPrefix(printedCount);
 }

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeConsoleSink.cs` around lines 39 - 43,
BuildIndentPrefix currently computes printedCount using scopes?.Count(s =>
s.Printed) but PrintUnopenedScopes guarantees every scope is marked printed
before BuildIndentPrefix is called, so the predicate is redundant; change the
computation in BuildIndentPrefix to use scopes?.Count ?? 0 to avoid an
unnecessary LINQ enumeration and rely on TreeScopeStateStore.ScopeState already
being marked by PrintUnopenedScopes, keeping the call to
TreeConsoleWriter.BuildPrefix(printedCount) unchanged.

src/TeaPie/Logging/TreeScopeStateStore.cs (2)

30-35: ImmutableStack<T>.Count() is O(n) on every Push.

ImmutableStack<T> does not expose an O(1) Count property; stack.Count() is the LINQ extension method that walks the linked list. For typical logging depths this is negligible, but it can be made O(1) by storing an explicit depth counter alongside the stack.

♻️ Optional: O(1) depth tracking

-    private static readonly AsyncLocal<ImmutableStack<ScopeState>> _current = new();
+    private static readonly AsyncLocal<(ImmutableStack<ScopeState> Stack, int Depth)> _current = new();

     internal static void Push(ScopeState state)
     {
-        var stack = _current.Value ?? ImmutableStack<ScopeState>.Empty;
-        state.Depth = stack.Count() + 1;
-        _current.Value = stack.Push(state);
+        var (stack, depth) = _current.Value;
+        stack ??= ImmutableStack<ScopeState>.Empty;
+        state.Depth = depth + 1;
+        _current.Value = (stack.Push(state), state.Depth);
     }

     internal static void Pop()
     {
-        var stack = _current.Value;
-        if (stack?.IsEmpty != false)
+        var (stack, depth) = _current.Value;
+        if (stack == null || stack.IsEmpty)
             return;
-        _current.Value = stack.Pop();
+        _current.Value = (stack.Pop(), depth - 1);
     }

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeScopeStateStore.cs` around lines 30 - 35, The Push
method currently calls stack.Count() which is O(n); change the storage from just
ImmutableStack<ScopeState> in _current to a small container that holds both the
ImmutableStack<ScopeState> and an int depth (e.g. a struct/tuple like (stack,
depth)), then in Push use that depth to set ScopeState.Depth = container.depth +
1 and set _current.Value to the new container with stack.Push(state) and
depth+1; also update the corresponding Pop/PopIfPresent logic to decrement the
depth when popping so the counter stays correct. Ensure you reference and update
_current, the Push method, any Pop method, ScopeState.Depth, and
ImmutableStack<ScopeState> consistently.

---

8-13: ScopeState properties can be internal to match the project's visibility policy.

Since the enclosing class is internal, public has no effect on the assembly API surface, but it conflicts with the project convention of avoiding unnecessary public visibility on members of non-public types.

♻️ Proposed change

 internal sealed class ScopeState
 {
-    public int Depth { get; set; }
-    public LogEventLevel? PrintedLevel { get; set; }
+    internal int Depth { get; set; }
+    internal LogEventLevel? PrintedLevel { get; set; }
     public bool Printed => PrintedLevel.HasValue;
 }

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeScopeStateStore.cs` around lines 8 - 13, The
ScopeState class exposes members as public despite the enclosing class being
internal; change the member visibility to internal: update the Depth property,
the PrintedLevel property, and the Printed computed property in the ScopeState
class (class name: ScopeState) from public to internal so they follow the
project's convention of not exposing public members on non-public types.

Configuration used: defaults

Review profile: CHILL

Plan: Pro

src/TeaPie/Logging/TreeConsoleWriter.cs (2)

24-32: Consider a lower-allocation prefix builder on the hot path.

Enumerable.Repeat + string.Concat is fine functionally, but this path can allocate more than necessary for frequent logs.

Proposed refactor

     internal static string BuildPrefix(int repeat)
     {
         if (repeat <= 0)
         {
             return string.Empty;
         }
 
-        return string.Concat(Enumerable.Repeat(VerticalBar, repeat));
+        var buffer = new System.Text.StringBuilder(repeat * VerticalBar.Length);
+        for (var i = 0; i < repeat; i++)
+        {
+            buffer.Append(VerticalBar);
+        }
+        return buffer.ToString();
     }

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeConsoleWriter.cs` around lines 24 - 32, BuildPrefix
currently uses Enumerable.Repeat + string.Concat which allocates extra objects
on the hot logging path; replace it with a lower-allocation implementation: if
VerticalBar is a single char (e.g. "|" ), return new string(VerticalBar[0],
repeat); otherwise pre-allocate a StringBuilder with capacity repeat *
VerticalBar.Length and append VerticalBar in a simple for loop and return
sb.ToString(); update the BuildPrefix method accordingly to use these branches
to minimize allocations.

---

17-22: Decouple writer output from Console.Out for better testability.

Hard-coding global console output makes this helper harder to unit-test and less reusable with redirected sinks.

Proposed refactor

+using System.IO;
 using Serilog.Events;
@@
-    internal static void WriteOpening(int depth, DateTimeOffset timestamp, string levelShort)
-        => WriteLine(StartCorner, depth, timestamp, levelShort);
+    internal static void WriteOpening(int depth, DateTimeOffset timestamp, string levelShort, TextWriter? writer = null)
+        => WriteLine(StartCorner, depth, timestamp, levelShort, writer ?? Console.Out);
@@
-    internal static void WriteClosing(int depth, DateTimeOffset timestamp, string levelShort)
-        => WriteLine(EndCorner, depth, timestamp, levelShort);
+    internal static void WriteClosing(int depth, DateTimeOffset timestamp, string levelShort, TextWriter? writer = null)
+        => WriteLine(EndCorner, depth, timestamp, levelShort, writer ?? Console.Out);
@@
-    private static void WriteLine(string corner, int depth, DateTimeOffset timestamp, string levelShort)
+    private static void WriteLine(string corner, int depth, DateTimeOffset timestamp, string levelShort, TextWriter writer)
     {
         var prefix = BuildPrefix(depth - 1);
         var header = BuildHeader(timestamp, levelShort);
-        Console.Out.WriteLine(header + " " + prefix + corner);
+        writer.WriteLine($"{header} {prefix}{corner}");
     }

🤖 Prompt for AI Agents

Verify each finding against the current code and only fix it if needed.

In `@src/TeaPie/Logging/TreeConsoleWriter.cs` around lines 17 - 22, The WriteLine
method in TreeConsoleWriter.cs is tightly coupled to Console.Out which prevents
injecting testable or redirected outputs; change WriteLine to accept a
TextWriter (or an instance field) and use that instead of Console.Out, update
callers to pass the desired TextWriter (e.g., Console.Out in production,
StringWriter in tests), and keep BuildPrefix and BuildHeader usage intact so
only the output sink changes; ensure any static usage of WriteLine is adjusted
to supply the writer or make the writer a configurable instance dependency.

Configuration used: defaults

Review profile: CHILL

Plan: Pro